Skip to content

gh-109461: Update logging module lock acquisition to use context manager#109462

Merged
vstinner merged 41 commits into
python:mainfrom
dcollison:gh-109461-update-logging-lock-acquisition
Sep 27, 2023
Merged

gh-109461: Update logging module lock acquisition to use context manager#109462
vstinner merged 41 commits into
python:mainfrom
dcollison:gh-109461-update-logging-lock-acquisition

Conversation

@dcollison

@dcollison dcollison commented Sep 15, 2023

Copy link
Copy Markdown
Contributor

Updated logging library to acquire its module lock using a context manager so that it is safer and easier to use.

…t manager so that it is safer and easier to use.
@dcollison
dcollison requested a review from vsajip as a code owner September 15, 2023 17:09
@ghost

ghost commented Sep 15, 2023

Copy link
Copy Markdown

All commit authors signed the Contributor License Agreement.
CLA signed

@bedevere-app

bedevere-app Bot commented Sep 15, 2023

Copy link
Copy Markdown

Most changes to Python require a NEWS entry.

Please add it using the blurb_it web app or the blurb command-line tool.

Comment thread Lib/logging/__init__.py Outdated
Comment thread Lib/logging/__init__.py
Comment thread Lib/logging/__init__.py Outdated
Comment thread Lib/logging/__init__.py Outdated
Comment thread Lib/logging/__init__.py Outdated
Comment thread Lib/logging/__init__.py Outdated
Comment thread Lib/logging/__init__.py Outdated
Comment thread Misc/NEWS.d/next/Library/2023-09-15-17-12-53.gh-issue-109461.VNFPTK.rst Outdated
@vsajip

vsajip commented Sep 22, 2023

Copy link
Copy Markdown
Member

I leave our logging expert to take the final decision

I'm away for a couple of weeks (with sporadic Internet access) and have set off tests in the buildbot fleet, with some results still to come in. If all the failures are unrelated to this change, I think we can merge this PR.

@vstinner

Copy link
Copy Markdown
Member

(...) have set off tests in the buildbot fleet, with some results still to come in. If all the failures are unrelated to this change, I think we can merge this PR.

Sadly, there are many unstable tests these days, I'm trying to fix most of them. I mean: most failures are unrelated to this PR. But someone has to check. Or later, you can rebase the PR on the main branch, and schedule a new buildbot job.

@AA-Turner AA-Turner added the 🔨 test-with-buildbots Test PR w/ buildbots; report in status section label Sep 26, 2023
@bedevere-bot

Copy link
Copy Markdown

🤖 New build scheduled with the buildbot fleet by @AA-Turner for commit 797ae0d 🤖

If you want to schedule another build, you need to add the 🔨 test-with-buildbots label again.

@bedevere-bot bedevere-bot removed the 🔨 test-with-buildbots Test PR w/ buildbots; report in status section label Sep 26, 2023
@AA-Turner

Copy link
Copy Markdown
Member

Ubuntu reports FAILURE then SUCCESS for test.test_multiprocessing_spawn.test_processes

@vstinner

Copy link
Copy Markdown
Member

Ubuntu reports FAILURE then SUCCESS for test.test_multiprocessing_spawn.test_processes

There are many unstable tests. All "FAILURE then SUCCESS" are unstable tests. They are unrelated to this change and you can ignore them.

You can browse into my issues https://github.com/python/cpython/issues/vstinner to see recent unstable tests.

@AA-Turner

Copy link
Copy Markdown
Member

10 buildbots failed:

  • FAILURE then FAILURE
    • PPC64 Fedora PR/1234 (test_sumprod_stress (test.test_math.MathTests.test_sumprod_stress) ... Timeout (0:15:00)!)
    • PPC64LE RHEL8 PR/1212 (test_pycfunction (test.test_gdb.PyBtTests.test_pycfunction) ... Timeout (0:15:00)!)
  • FAILURE then SUCCESS:
    • AMD64 Debian root PR/1243
    • ARM64 macOS PR/1254
    • PPC64LE Fedora Stable Refleaks PR/1355
    • PPC64LE RHEL7 PR/1195
    • s390x RHEL8 PR/1210
  • ENV CHANGED then SUCCESS
    • PPC64LE RHEL7 Refleaks PR/1387
    • PPC64LE RHEL8 Refleaks PR/1428
  • Timed out
    • AMD64 Windows11 Refleaks PR/114: test.test_concurrent_futures.test_shutdown (after 2 hour 49 min)

None seem logging related, so seems safe to merge.

A

@vstinner

Copy link
Copy Markdown
Member

@vsajip, maintainer of logging wrote:

I'm away for a couple of weeks (with sporadic Internet access) and have set off tests in the buildbot fleet, with some results still to come in. If all the failures are unrelated to this change, I think we can merge this PR.

In short, he approved the PR.

@vstinner
vstinner merged commit 74723e1 into python:main Sep 27, 2023
@vstinner

Copy link
Copy Markdown
Member

Merged. Thanks @dcollison, it's a nice cleanup. It may make the logging safer, since with lock: is treated differently than the lock.acquire() try: ... finally: lock.release() pattern. A with block doesn't handle signals at the bytecode level. To avoid messing a lock when a signal is received (like CTRL+C).

Example in Python 3.10, see also issue gh-74225:

        if (_Py_atomic_load_relaxed(eval_breaker)) {
            opcode = _Py_OPCODE(*next_instr);
            if (opcode != SETUP_FINALLY &&
                opcode != SETUP_WITH &&
                opcode != BEFORE_ASYNC_WITH &&
                opcode != YIELD_FROM) {
                /* Few cases where we skip running signal handlers and other
                   pending calls:
                   - If we're about to enter the 'with:'. It will prevent
                     emitting a resource warning in the common idiom
                     'with open(path) as file:'.
                   - If we're about to enter the 'async with:'.
                   - If we're about to enter the 'try:' of a try/finally (not
                     *very* useful, but might help in some cases and it's
                     traditional)
                   - If we're resuming a chain of nested 'yield from' or
                     'await' calls, then each frame is parked with YIELD_FROM
                     as its next opcode. If the user hit control-C we want to
                     wait until we've reached the innermost frame before
                     running the signal handler and raising KeyboardInterrupt
                     (see bpo-30039).
                */
                if (eval_frame_handle_pending(tstate) != 0) {
                    goto error;
                }
             }
        }

@bedevere-bot

Copy link
Copy Markdown

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Hi! The buildbot AMD64 Fedora Stable Clang 3.x has failed when building commit 74723e1.

What do you need to do:

  1. Don't panic.
  2. Check the buildbot page in the devguide if you don't know what the buildbots are or how they work.
  3. Go to the page of the buildbot that failed (https://buildbot.python.org/all/#builders/441/builds/4565) and take a look at the build logs.
  4. Check if the failure is related to this commit (74723e1) or if it is a false positive.
  5. If the failure is related to this commit, please, reflect that on the issue and make a new Pull Request with a fix.

You can take a look at the buildbot page here:

https://buildbot.python.org/all/#builders/441/builds/4565

Failed tests:

  • test.test_multiprocessing_fork.test_processes

Summary of the results of the build (if available):

==

Click to see traceback logs
remote: Enumerating objects: 16, done.        
remote: Counting objects:   7% (1/14)        
remote: Counting objects:  14% (2/14)        
remote: Counting objects:  21% (3/14)        
remote: Counting objects:  28% (4/14)        
remote: Counting objects:  35% (5/14)        
remote: Counting objects:  42% (6/14)        
remote: Counting objects:  50% (7/14)        
remote: Counting objects:  57% (8/14)        
remote: Counting objects:  64% (9/14)        
remote: Counting objects:  71% (10/14)        
remote: Counting objects:  78% (11/14)        
remote: Counting objects:  85% (12/14)        
remote: Counting objects:  92% (13/14)        
remote: Counting objects: 100% (14/14)        
remote: Counting objects: 100% (14/14), done.        
remote: Compressing objects:  11% (1/9)        
remote: Compressing objects:  22% (2/9)        
remote: Compressing objects:  33% (3/9)        
remote: Compressing objects:  44% (4/9)        
remote: Compressing objects:  55% (5/9)        
remote: Compressing objects:  66% (6/9)        
remote: Compressing objects:  77% (7/9)        
remote: Compressing objects:  88% (8/9)        
remote: Compressing objects: 100% (9/9)        
remote: Compressing objects: 100% (9/9), done.        
remote: Total 16 (delta 5), reused 6 (delta 5), pack-reused 2        
From https://github.com/python/cpython
 * branch                  main       -> FETCH_HEAD
Note: switching to '74723e11109a320e628898817ab449b3dad9ee96'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by switching back to a branch.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -c with the switch command. Example:

  git switch -c <new-branch-name>

Or undo this operation with:

  git switch -

Turn off this advice by setting config variable advice.detachedHead to false

HEAD is now at 74723e1110 gh-109461: Update logging module lock to use context manager (#109462)
Switched to and reset branch 'main'

make: *** [Makefile:2040: buildbottest] Error 5

@bedevere-bot

Copy link
Copy Markdown

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Hi! The buildbot aarch64 Fedora Stable LTO + PGO 3.x has failed when building commit 74723e1.

What do you need to do:

  1. Don't panic.
  2. Check the buildbot page in the devguide if you don't know what the buildbots are or how they work.
  3. Go to the page of the buildbot that failed (https://buildbot.python.org/all/#builders/524/builds/4572) and take a look at the build logs.
  4. Check if the failure is related to this commit (74723e1) or if it is a false positive.
  5. If the failure is related to this commit, please, reflect that on the issue and make a new Pull Request with a fix.

You can take a look at the buildbot page here:

https://buildbot.python.org/all/#builders/524/builds/4572

Summary of the results of the build (if available):

==

Click to see traceback logs
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-stable-aarch64.lto-pgo/build/Lib/threading.py", line 1066, in _bootstrap_inner
    self.run()
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-stable-aarch64.lto-pgo/build/Lib/threading.py", line 1003, in run
    self._target(*self._args, **self._kwargs)
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-stable-aarch64.lto-pgo/build/Lib/test/test_interpreters.py", line 483, in task
    interp = interpreters.create()
             ^^^^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-stable-aarch64.lto-pgo/build/Lib/test/support/interpreters.py", line 25, in create
    id = _interpreters.create(isolated=isolated)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
RuntimeError: interpreter creation failed
k


Traceback (most recent call last):
  File "<frozen importlib._bootstrap>", line 1354, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1325, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 929, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 1004, in exec_module
  File "<frozen importlib._bootstrap_external>", line 1100, in get_code
  File "<frozen importlib._bootstrap_external>", line 1199, in get_data
TypeError: descriptor 'close' for '_io.BufferedReader' objects doesn't apply to a '_io.FileIO' object

csm10495 pushed a commit to csm10495/cpython that referenced this pull request Sep 28, 2023
@dcollison
dcollison deleted the gh-109461-update-logging-lock-acquisition branch September 28, 2023 08:45
@vsajip vsajip mentioned this pull request Nov 18, 2023
Glyphack pushed a commit to Glyphack/cpython that referenced this pull request Sep 2, 2024
cjwatson added a commit to cjwatson/pastescript that referenced this pull request Dec 8, 2024
python/cpython#109462 removed
`logging._acquireLock`.  Fortunately,
python/cpython#3385 simplified lock creation so
that `with logging._lock:` is sufficient; that PR made it into Python
3.7, which is already pastescript's minimum Python requirement.
cdent pushed a commit to pasteorg/pastescript that referenced this pull request Jan 22, 2025
python/cpython#109462 removed
`logging._acquireLock`.  Fortunately,
python/cpython#3385 simplified lock creation so
that `with logging._lock:` is sufficient; that PR made it into Python
3.7, which is already pastescript's minimum Python requirement.
SeungjinYang added a commit to skypilot-org/skypilot that referenced this pull request Jul 14, 2026
…eadlock on Python < 3.13 (#10104)

* [k8s] Set urllib3 log level once per process instead of on every API call

Previously, _api_logging_decorator re-decorated every method of the
Kubernetes client on each API getter call, so every k8s API method
invocation entered the set_logging_level context manager and called
Logger.setLevel() twice (suppress + restore). setLevel() acquires the
logging module's process-wide lock via Manager._clear_cache(); on
Python < 3.13, a fork() while another thread holds that lock leaves it
permanently held in the child, deadlocking the child's next logging
call (fixed upstream in python/cpython#109462,
which SkyPilot cannot rely on yet).

Set the urllib3 logger level to ERROR once per process on first k8s
API use instead. The old per-call set/restore was already racy under
concurrent API calls (interleaved restores routinely left the level
stuck at ERROR), so this preserves the effective behavior while
shrinking the fork-deadlock window to a single one-time setLevel().
Also removes the per-call dir()/getattr sweep over the client wrapper.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* [k8s] Drop redundant lock around one-time setLevel per review

Set membership/add are GIL-atomic and a duplicate setLevel() from a
racing first call is idempotent, so the double-checked lock is
unnecessary — and it would itself be a lock a fork could leave
permanently held in the child.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* [Core] Remove now-unused sky_logging.set_logging_level

Its only caller was the kubernetes adaptor's per-call log suppression,
removed earlier in this PR. The per-call set/restore pattern it enables
is what made the pre-3.13 fork deadlock easy to hit, so drop it rather
than leave it around to be reused.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* [Test] Add regression test for one-time urllib3 log suppression

Verifies that a k8s API getter suppresses urllib3 warnings (via the
effective level inherited by child loggers like urllib3.connectionpool)
and that Logger.setLevel() is called exactly once per process across
repeated and cross-API calls.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* [k8s] Re-assert urllib3 log level after client construction

Real-cluster testing (sky check against an unreachable context) showed
urllib3 retry warnings still leaking: kubernetes.client.Configuration
resets the urllib3 logger to WARNING in __init__ (its debug property
setter), stomping the once-per-process level set. The old per-call
set/restore masked this by re-setting the level at every method call,
after construction.

Re-assert the level after the decorated getter runs, guarded by a
lock-free level read so setLevel() only fires when a client
construction actually reset it — once per new client (per context /
refresh), not per API call. Updated the regression test to simulate
the Configuration reset, which the previous test missed by mocking
_get_api_client.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants